**** dT    0.000
*    top   TEST ../../../../bin/varnishtest/tests/b00020.vtc starting
**** top   extmacro def pkg_version=trunk
**** top   extmacro def pkg_branch=trunk
**** top   extmacro def pwd=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:46027
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   extmacro def topbuild=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub
**** top   extmacro def topsrc=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/../..
**** top   macro def testdir=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest/../../../../bin/varnishtest/tests
**** top   macro def tmpdir=/home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803
**** top   macro def vtcid=vtc.3707526.4a3bf803
**   top   === varnishtest "Check that between_bytes_timeout behaves from p...
*    top   VTEST Check that between_bytes_timeout behaves from parameters
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=37553
**** s1    macro def s1_sock=127.0.0.1:37553
*    s1    Listen on 127.0.0.1:37553
**   top   === varnish v1 -vcl+backend {
**** dT    0.004
**   s1    Started on 127.0.0.1:37553 (1 iterations)
**** dT    0.015
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 36665' -P /home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    CMD: cd /home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/bin/varnishtest && exec varnishd  -d -n /home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 36665' -P /home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803/v1/varnishd.pid -p vmod_path=/home/linux1/VT/varnish-cache/varnish-trunk/_build/sub/vmod/.libs 
***  v1    PID: 3707545
**** v1    macro def v1_pid=3707545
**** v1    macro def v1_name=/home/linux1/VT/_vtest_tmp/vtc.3707526.4a3bf803/v1
**** dT    0.020
***  v1    debug|Info: Working directory not mounted on tmpfs partition
***  v1    debug|
**** dT    0.029
***  v1    debug|Debug: Version: varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e
***  v1    debug|Debug: Platform: Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 329     
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e
***  v1    debug|
***  v1    debug|Type 'help' for command list.
***  v1    debug|Type 'quit' to close CLI session.
***  v1    debug|Type 'start' to launch worker process.
***  v1    debug|
**** dT    0.132
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
***  v1    CLI RX  107
**** v1    CLI RX|vuwarrebdhdoxvonoeyqxuxemoawmpmb
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** v1    CLI TX|auth f187c4d62b66dfd1f09e1197b0f57aacc9ef6144bece34e7b7206380d3c7e176
**** dT    0.138
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,4.18.0-553.44.1.el8_10.s390x,s390x,-jlinux,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-trunk revision f37cebe89eadb4bdb00b8825a6677044ddca7c9e
**** v1    CLI RX|
**** v1    CLI RX|Type 'help' for command list.
**** v1    CLI RX|Type 'quit' to close CLI session.
**** v1    CLI RX|Type 'start' to launch worker process.
**** dT    0.139
**** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "37553"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\tsub vcl_backend_response {
**** v1    CLI TX|\t\tset beresp.do_stream = false;
**** v1    CLI TX|\t}
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.247
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.351
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.452
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.515
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    0.553
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.580
***  v1    debug|Debug: Child (3707558) Started
**** dT    0.625
***  v1    debug|Child launched OK
**** dT    0.628
***  v1    debug|Info: Child (3707558) said Child starts
**** dT    0.629
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
**** dT    0.630
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
**** dT    0.654
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1742872790.744186/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1742872790.744186/vgc.so" as "vcl1"
**** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    vsl|          0 CLI             - Wr 200 0 
**** v1    vsl|          0 CLI             - Rd start
**** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:44429
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:44429
**** v1    vsl|          0 CLI             - Wr 200 0 
**** dT    0.758
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** dT    0.777
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44429
**** v1    CLI TX|debug.xid 1000
**** dT    0.783
***  v1    CLI RX  200
**** v1    CLI RX|XID is 1000 chunk 1
**** v1    CLI TX|debug.listen_address
**** dT    0.836
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 44429
**   v1    Listen on 127.0.0.1 44429
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=44429
**** v1    macro def v1_sock=127.0.0.1:44429
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=44429
**** v1    macro def v1_a0_sock=127.0.0.1:44429
**   top   === varnish v1 -cliok "param.set between_bytes_timeout 1"
**** v1    CLI TX|param.set between_bytes_timeout 1
**** dT    0.859
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44429

**** v1    vsl|          0 CLI             - Rd debug.xid 1000 
**** v1    vsl|          0 CLI             - Wr 200 19 XID is 1000 chunk 1
**** v1    vsl|          0 CLI             - Rd debug.listen_address 
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 44429

**** dT    0.882
***  v1    CLI RX  200
**   v1    CLI 200 <param.set between_bytes_timeout 1>
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:44429 (1 iterations)
***  c1    Connect to 127.0.0.1:44429
***  c1    connected fd 17 from 127.0.0.1 53868 to 127.0.0.1:44429
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|User-Agent: c1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    0.892
***  s1    accepted fd 5 127.0.0.1 37988
**   s1    === rxreq
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|User-Agent: c1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |User-Agent: c1
**** s1    http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 7] |Accept-Encoding: gzip
**** s1    http[ 8] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === send "HTTP/1.0 200 OK\r\nConnection: close\r\n\r\n"
**** s1    send|HTTP/1.0 200 OK\r
**** s1    send|Connection: close\r
**** s1    send|\r
**   s1    === delay 1.5
***  s1    delaying 1.5 second(s)
**** dT    0.961
**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 53868 a0 127.0.0.1 44429 1742872791.491461 22
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** dT    1.905
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Date: Tue, 25 Mar 2025 03:19:52 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Content-Length: 281\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 246
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Date: Tue, 25 Mar 2025 03:19:52 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |Content-Type: text/html; charset=utf-8
**** c1    http[ 6] |Retry-After: 5
**** c1    http[ 7] |X-Varnish: 1001
**** c1    http[ 8] |Age: 0
**** c1    http[ 9] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[10] |Content-Length: 281
**** c1    http[11] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1002</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 281
**   c1    === expect resp.status == 503
**** c1    EXPECT resp.status (503) == "503" match
***  c1    closing fd 17
**   c1    Ending
**** dT    1.910
**   top   === delay 1
***  top   delaying 1 second(s)
**** dT    1.980
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1742872791.494467 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b User-Agent: c1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1002 VCL_return      b fetch
**** v1    vsl|       1002 Timestamp       b Fetch: 1742872791.494495 0.000027 0.000027
**** v1    vsl|       1002 Timestamp       b Connected: 1742872791.494556 0.000088 0.000061
**** v1    vsl|       1002 BackendOpen     b 25 s1 127.0.0.1 37553 127.0.0.1 37988 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1742872791.494586 0.000118 0.000030
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.0
**** v1    vsl|       1002 BerespStatus    b 200
**** v1    vsl|       1002 BerespReason    b OK
**** v1    vsl|       1002 BerespHeader    b Connection: close
**** v1    vsl|       1002 Timestamp       b Beresp: 1742872791.496970 0.002502 0.002383
**** v1    vsl|       1002 BerespHeader    b Date: Tue, 25 Mar 2025 03:19:51 GMT
**** v1    vsl|       1002 TTL             b RFC 120 10 0 1742872791 1742872791 1742872791 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Debug           b Missing content-range header or unknown range unit
**** v1    vsl|       1002 Timestamp       b Process: 1742872791.497052 0.002584 0.000082
**** v1    vsl|       1002 Filters         b 
**** v1    vsl|       1002 Storage         b malloc s0
**** v1    vsl|       1002 Fetch_Body      b 4 eof -
**** v1    vsl|       1002 FetchError      b Resource temporarily unavailable
**** v1    vsl|       1002 FetchError      b eof socket fail
**** v1    vsl|       1002 BackendClose    b 25 s1 close RX_BODY
**** v1    vsl|       1002 Timestamp       b Error: 1742872792.504247 1.009779 1.007194
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 503
**** v1    vsl|       1002 BerespReason    b Backend fetch failed
**** v1    vsl|       1002 BerespHeader    b Date: Tue, 25 Mar 2025 03:19:52 GMT
**** v1    vsl|       1002 BerespHeader    b Server: Varnish
**** v1    vsl|       1002 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1002 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v1    vsl|       1002 BerespHeader    b Retry-After: 5
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Storage         b malloc Transient
**** v1    vsl|       1002 Length          b 281
**** v1    vsl|       1002 BereqAcct       b 148 0 148 38 0 38
**** v1    vsl|       1002 End             b 
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1742872791.491509 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1742872791.491509 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 53868 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c User-Agent: c1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 VCL_return      c hash
**** v1    vsl|       1001 VCL_call        c HASH
**** v1    vsl|       1001 VCL_return      c lookup
**** v1    vsl|       1001 VCL_call        c MISS
**** v1    vsl|       1001 VCL_return      c fetch
**** v1    vsl|       1001 Link            c bereq 1002 fetch
**** v1    vsl|       1001 Timestamp       c Fetch: 1742872792.505199 1.013689 1.013689
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 503
**** v1    vsl|       1001 RespReason      c Backend fetch failed
**** v1    vsl|       1001 RespHeader      c Date: Tue, 25 Mar 2025 03:19:52 GMT
**** v1    vsl|       1001 RespHeader      c Server: Varnish
**** v1    vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1001 RespHeader      c Retry-After: 5
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1001 VCL_call        c DELIVER
**** v1    vsl|       1001 VCL_return      c deliver
**** v1    vsl|       1001 Timestamp       c Process: 1742872792.505257 1.013747 0.000058
**** v1    vsl|       1001 Filters         c 
**** v1    vsl|       1001 RespHeader      c Content-Length: 281
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 Timestamp       c Resp: 1742872792.505330 1.013821 0.000073
**** v1    vsl|       1001 ReqAcct         c 51 0 51 246 281 527
**** v1    vsl|       1001 End             c 
**** v1    vsl|       1000 SessClose       c REM_CLOSE 1.020
**** v1    vsl|       1000 End             c 
**** dT    2.395
***  s1    shutting fd 5
**   s1    Ending
**** dT    2.911
**   top   === varnish v1 -expect n_object == 0
**** dT    2.912
**   v1    as expected: n_object (0) == 0 (0)
**   top   === varnish v1 -expect n_objectcore == 0
**   v1    as expected: n_objectcore (0) == 0 (0)
**   top   === server s1 -wait {
**   s1    Waiting for server (4/-1)
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=37553
**** s1    macro def s1_sock=127.0.0.1:37553
*    s1    Listen on 127.0.0.1:37553
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**** dT    2.913
**   c1    Started on 127.0.0.1:44429 (1 iterations)
***  c1    Connect to 127.0.0.1:44429
***  c1    connected fd 18 from 127.0.0.1 53872 to 127.0.0.1:44429
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|User-Agent: c1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    2.916
**   s1    Started on 127.0.0.1:37553 (1 iterations)
**** dT    2.926
***  s1    accepted fd 19 127.0.0.1 37998
**   s1    === non_fatal
**   s1    === rxreq
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|User-Agent: c1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1005\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 148
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |User-Agent: c1
**** s1    http[ 5] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 6] |Via: 1.1 v1 (Varnish/trunk)
**** s1    http[ 7] |Accept-Encoding: gzip
**** s1    http[ 8] |X-Varnish: 1005
**** s1    bodylen = 0
**   s1    === send "HTTP/1.0 200 OK\r\nConnection: close\r\n\r\n"
**** s1    send|HTTP/1.0 200 OK\r
**** s1    send|Connection: close\r
**** s1    send|\r
**   s1    === delay 0.5
***  s1    delaying 0.5 second(s)
**** dT    2.995
**** v1    vsl|       1003 Begin           c sess 0 HTTP/1
**** v1    vsl|       1003 SessOpen        c 127.0.0.1 53872 a0 127.0.0.1 44429 1742872793.524107 23
**** v1    vsl|       1003 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:44429
**** v1    vsl|       1003 Link            c req 1004 rxreq
**** dT    3.704
**** v1    vsl|          0 CLI             - Rd ping
**** v1    vsl|          0 CLI             - Wr 200 19 PONG 1742872794 1.0
**** dT    3.981
**** c1    rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c1    rxhdr|Date: Tue, 25 Mar 2025 03:19:54 GMT\r
**** c1    rxhdr|Server: Varnish\r
**** c1    rxhdr|Content-Type: text/html; charset=utf-8\r
**** c1    rxhdr|Retry-After: 5\r
**** c1    rxhdr|X-Varnish: 1004\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/trunk)\r
**** c1    rxhdr|Content-Length: 281\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 246
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |503
**** c1    http[ 2] |Backend fetch failed
**** c1    http[ 3] |Date: Tue, 25 Mar 2025 03:19:54 GMT
**** c1    http[ 4] |Server: Varnish
**** c1    http[ 5] |Content-Type: text/html; charset=utf-8
**** c1    http[ 6] |Retry-After: 5
**** c1    http[ 7] |X-Varnish: 1004
**** c1    http[ 8] |Age: 0
**** c1    http[ 9] |Via: 1.1 v1 (Varnish/trunk)
**** c1    http[10] |Content-Length: 281
**** c1    http[11] |Connection: keep-alive
**** c1    c-l|<!DOCTYPE html>
**** c1    c-l|<html>
**** c1    c-l|  <head>
**** c1    c-l|    <title>503 Backend fetch failed</title>
**** c1    c-l|  </head>
**** c1    c-l|  <body>
**** c1    c-l|    <h1>Error 503 Backend fetch failed</h1>
**** c1    c-l|    <p>Backend fetch failed</p>
**** c1    c-l|    <h3>Guru Meditation:</h3>
**** c1    c-l|    <p>XID: 1005</p>
**** c1    c-l|    <hr>
**** c1    c-l|    <p>Varnish cache server</p>
**** c1    c-l|  </body>
**** c1    c-l|</html>
**** c1    bodylen = 281
**   c1    === expect resp.status == 200
---- c1    EXPECT resp.status (503) == "200" failed
**** dT    3.983
*    top   RESETTING after ../../../../bin/varnishtest/tests/b00020.vtc
**   s1    Waiting for server (4/-1)
**** dT    4.009
**** v1    vsl|       1005 Begin           b bereq 1004 fetch
**** v1    vsl|       1005 VCL_use         b vcl1
**** v1    vsl|       1005 Timestamp       b Start: 1742872793.527722 0.000000 0.000000
**** v1    vsl|       1005 BereqMethod     b GET
**** v1    vsl|       1005 BereqURL        b /
**** v1    vsl|       1005 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1005 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b User-Agent: c1
**** v1    vsl|       1005 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1005 BereqHeader     b Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1005 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1005 BereqHeader     b X-Varnish: 1005
**** v1    vsl|       1005 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1005 VCL_return      b fetch
**** v1    vsl|       1005 Timestamp       b Fetch: 1742872793.527749 0.000026 0.000026
**** v1    vsl|       1005 Timestamp       b Connected: 1742872793.527796 0.000073 0.000046
**** v1    vsl|       1005 BackendOpen     b 25 s1 127.0.0.1 37553 127.0.0.1 37998 connect
**** v1    vsl|       1005 Timestamp       b Bereq: 1742872793.527823 0.000100 0.000027
**** v1    vsl|       1005 BerespProtocol  b HTTP/1.0
**** v1    vsl|       1005 BerespStatus    b 200
**** v1    vsl|       1005 BerespReason    b OK
**** v1    vsl|       1005 BerespHeader    b Connection: close
**** v1    vsl|       1005 Timestamp       b Beresp: 1742872793.532229 0.004506 0.004405
**** v1    vsl|       1005 BerespHeader    b Date: Tue, 25 Mar 2025 03:19:53 GMT
**** v1    vsl|       1005 TTL             b RFC 120 10 0 1742872794 1742872794 1742872793 0 0 cacheable
**** v1    vsl|       1005 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1005 VCL_return      b deliver
**** v1    vsl|       1005 Debug           b Missing content-range header or unknown range unit
**** v1    vsl|       1005 Timestamp       b Process: 1742872793.532257 0.004534 0.000028
**** v1    vsl|       1005 Filters         b 
**** v1    vsl|       1005 Storage         b malloc s0
**** v1    vsl|       1005 Fetch_Body      b 4 eof -
**** v1    vsl|       1005 FetchError      b Resource temporarily unavailable
**** v1    vsl|       1005 FetchError      b eof socket fail
**** v1    vsl|       1005 BackendClose    b 25 s1 close RX_BODY
**** v1    vsl|       1005 Timestamp       b Error: 1742872794.583627 1.055904 1.051369
**** v1    vsl|       1005 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1005 BerespStatus    b 503
**** v1    vsl|       1005 BerespReason    b Backend fetch failed
**** v1    vsl|       1005 BerespHeader    b Date: Tue, 25 Mar 2025 03:19:54 GMT
**** v1    vsl|       1005 BerespHeader    b Server: Varnish
**** v1    vsl|       1005 VCL_call        b BACKEND_ERROR
**** v1    vsl|       1005 BerespHeader    b Content-Type: text/html; charset=utf-8
**** v1    vsl|       1005 BerespHeader    b Retry-After: 5
**** v1    vsl|       1005 VCL_return      b deliver
**** v1    vsl|       1005 Storage         b malloc Transient
**** v1    vsl|       1005 Length          b 281
**** v1    vsl|       1005 BereqAcct       b 148 0 148 38 0 38
**** v1    vsl|       1005 End             b 
**** v1    vsl|       1004 Begin           c req 1003 rxreq
**** v1    vsl|       1004 Timestamp       c Start: 1742872793.524165 0.000000 0.000000
**** v1    vsl|       1004 Timestamp       c Req: 1742872793.524165 0.000000 0.000000
**** v1    vsl|       1004 VCL_use         c vcl1
**** v1    vsl|       1004 ReqStart        c 127.0.0.1 53872 a0
**** v1    vsl|       1004 ReqMethod       c GET
**** v1    vsl|       1004 ReqURL          c /
**** v1    vsl|       1004 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1004 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1004 ReqHeader       c User-Agent: c1
**** v1    vsl|       1004 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1004 ReqHeader       c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1004 VCL_call        c RECV
**** v1    vsl|       1004 VCL_return      c hash
**** v1    vsl|       1004 VCL_call        c HASH
**** v1    vsl|       1004 VCL_return      c lookup
**** v1    vsl|       1004 VCL_call        c MISS
**** v1    vsl|       1004 VCL_return      c fetch
**** v1    vsl|       1004 Link            c bereq 1005 fetch
**** v1    vsl|       1004 Timestamp       c Fetch: 1742872794.585759 1.061594 1.061594
**** v1    vsl|       1004 RespProtocol    c HTTP/1.1
**** v1    vsl|       1004 RespStatus      c 503
**** v1    vsl|       1004 RespReason      c Backend fetch failed
**** v1    vsl|       1004 RespHeader      c Date: Tue, 25 Mar 2025 03:19:54 GMT
**** v1    vsl|       1004 RespHeader      c Server: Varnish
**** v1    vsl|       1004 RespHeader      c Content-Type: text/html; charset=utf-8
**** v1    vsl|       1004 RespHeader      c Retry-After: 5
**** v1    vsl|       1004 RespHeader      c X-Varnish: 1004
**** v1    vsl|       1004 RespHeader      c Age: 0
**** v1    vsl|       1004 RespHeader      c Via: 1.1 v1 (Varnish/trunk)
**** v1    vsl|       1004 VCL_call        c DELIVER
**** v1    vsl|       1004 VCL_return      c deliver
**** v1    vsl|       1004 Timestamp       c Process: 1742872794.585795 1.061630 0.000035
**** v1    vsl|       1004 Filters         c 
**** v1    vsl|       1004 RespHeader      c Content-Length: 281
**** v1    vsl|       1004 RespHeader      c Connection: keep-alive
**** v1    vsl|       1004 Timestamp       c Resp: 1742872794.585857 1.061692 0.000062
**** v1    vsl|       1004 ReqAcct         c 51 0 51 246 281 527
**** v1    vsl|       1004 End             c 
**** dT    4.307
**   v1    Wait
**** v1    CLI TX|panic.show
**** dT    4.352
***  v1    CLI RX  300
**** v1    CLI RX|Child has not panicked or panic has been cleared
**** dT    4.353
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    4.413
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    4.455
***  v1    debug|Info: Child (3707558) said Child dies
***  v1    debug|Info: Child (3707558) ended
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** dT    4.461
**** v1    STDOUT EOF
**** dT    4.516
**   v1    WAIT4 pid=3707545 status=0x0000 (user 0.231119 sys 0.031380)
*    top   TEST ../../../../bin/varnishtest/tests/b00020.vtc FAILED
#    top  TEST ../../../../bin/varnishtest/tests/b00020.vtc FAILED (4.521) exit=2
FAIL tests/b00020.vtc (exit status: 2)